Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add some performance instrumentation to our code #1972

Merged
merged 4 commits into from
Dec 9, 2022

Conversation

celinval
Copy link
Contributor

@celinval celinval commented Dec 6, 2022

Description of changes:

For runs using --verbose, Kani will now print the time spent in some parts of the code. This include calls to all CProver utilities and a few other places in the compiler.

Resolved issues:

N/A

Related RFC:

Call-outs:

Note that the time measured in run_cbmc includes parsing the results. This is similar to the "Verification Time" we print, but it can be misleading when we are using debug mode, since it can more than double the actual time we report to be the verification time. We should probably improve that, but it's out of the scope of this PR. The overhead is also small when running a release build.

Testing:

  • How is this change tested?

  • Is this a refactor change?

Checklist

  • Each commit message has a non-empty body, explaining why the change was made
  • Methods or procedures are documented
  • Regression or unit tests are included, or existing tests cover the modified code
  • My PR is restricted to a single feature or bugfix

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 and MIT licenses.

@celinval celinval requested a review from a team as a code owner December 6, 2022 20:54
Copy link
Contributor

@zhassan-aws zhassan-aws left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for doing this!

I only had a few minor comments.

@@ -490,3 +503,14 @@ where
serde_json::to_writer(writer, &source).unwrap();
}
}

pub fn with_timer<T, F>(func: F, description: &str) -> T
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add documentation

@@ -82,58 +83,66 @@ impl CodegenBackend for GotocCodegenBackend {
check_options(tcx.sess, need_metadata_module);
check_crate_items(&gcx);

let items = collect_codegen_items(&gcx);
let items = with_timer(|| collect_codegen_items(&gcx), "reachability analysis");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we be more specific, e.g. "codegen items reachability analysis"?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed it to be "codegen reachability analysis". Let me know if that's OK.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good.

@@ -191,6 +203,19 @@ impl KaniSession {

Ok(Some(process))
}

pub fn with_timer<T, F>(&self, func: F, description: &str) -> T
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be worth creating a "common" or "utils" crate at some point that includes this function (and similar ones) to avoid duplication.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I totally agree. Not sure it's worth it in this PR though

@celinval celinval force-pushed the issue-xxxx-instrument-perf branch from 9ca5528 to 2fcd508 Compare December 9, 2022 05:34
@celinval celinval merged commit bb019b0 into model-checking:main Dec 9, 2022
@@ -117,6 +117,9 @@ impl KaniSession {

if self.args.debug {
flags.push("--log-level=debug".into());
} else if self.args.verbose {
// Print the symtab command being invoked.
flags.push("--log-level=info".into());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was removed in #1730 is the underlying issue fixed there?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants